Skip to content

[feat](log) Add more log about cost time for dropTable#30284

Merged
yiguolei merged 1 commit intoapache:masterfrom
swjtu-zhanglei:master-fix5
Jan 25, 2024
Merged

[feat](log) Add more log about cost time for dropTable#30284
yiguolei merged 1 commit intoapache:masterfrom
swjtu-zhanglei:master-fix5

Conversation

@swjtu-zhanglei
Copy link
Contributor

  • In some p0 test cases we have found dropTable cost more than 5 seconds, so add more time cost log

Proposed changes

Issue Number: close #xxx

Further comments

If this is a relatively large or complex change, kick off the discussion at dev@doris.apache.org by explaining why you chose the solution you did and what alternatives you considered, etc...

@swjtu-zhanglei swjtu-zhanglei marked this pull request as ready for review January 23, 2024 13:03
@swjtu-zhanglei
Copy link
Contributor Author

run buildall

@doris-robot
Copy link

TPC-H: Total hot run time: 38963 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit e842dd05906946aa34f00ee1eb0ab2ac68e75e33, data reload: false

------ Round 1 ----------------------------------
q1	18209	5314	5443	5314
q2	2553	146	136	136
q3	11485	1196	1242	1196
q4	10914	765	798	765
q5	8007	3283	3202	3202
q6	202	122	124	122
q7	876	524	506	506
q8	9264	1922	1955	1922
q9	7254	6364	6342	6342
q10	8229	3007	3079	3007
q11	423	207	198	198
q12	359	190	193	190
q13	17976	3331	3335	3331
q14	244	219	210	210
q15	547	507	496	496
q16	428	390	375	375
q17	939	503	515	503
q18	7442	6933	6744	6744
q19	1582	1352	1409	1352
q20	560	322	312	312
q21	2758	2415	2423	2415
q22	375	325	325	325
Total cold run time: 110626 ms
Total hot run time: 38963 ms

----- Round 2, with runtime_filter_mode=off -----
q1	5451	5300	5351	5300
q2	324	220	213	213
q3	3371	3216	3254	3216
q4	2107	2054	2040	2040
q5	6000	5821	5869	5821
q6	199	115	116	115
q7	2381	1935	1902	1902
q8	3227	3375	3390	3375
q9	9042	8801	8951	8801
q10	3968	3799	3834	3799
q11	553	453	452	452
q12	803	619	666	619
q13	16924	3151	3142	3142
q14	284	262	277	262
q15	551	506	506	506
q16	506	452	455	452
q17	1869	1875	1849	1849
q18	9490	18009	9503	9503
q19	22122	1525	1540	1525
q20	4607	1944	1920	1920
q21	14476	5371	5388	5371
q22	968	537	574	537
Total cold run time: 109223 ms
Total hot run time: 60720 ms

@doris-robot
Copy link

TPC-DS: Total hot run time: 185962 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit e842dd05906946aa34f00ee1eb0ab2ac68e75e33, data reload: false

query1	941	331	331	331
query2	6563	2154	1920	1920
query3	6701	200	196	196
query4	33067	22042	22067	22042
query5	4451	373	360	360
query6	243	160	152	152
query7	4617	258	260	258
query8	234	179	188	179
query9	8329	2560	2532	2532
query10	421	227	238	227
query11	16888	15452	15437	15437
query12	132	69	65	65
query13	1671	364	376	364
query14	10533	6971	6958	6958
query15	217	180	185	180
query16	5788	250	242	242
query17	966	473	465	465
query18	1810	268	254	254
query19	170	132	127	127
query20	72	69	65	65
query21	194	131	128	128
query22	5052	4711	4760	4711
query23	31554	30977	30827	30827
query24	12616	2830	2795	2795
query25	567	309	307	307
query26	1816	147	153	147
query27	3204	282	289	282
query28	7192	1829	1815	1815
query29	2188	634	630	630
query30	279	140	142	140
query31	954	742	736	736
query32	86	57	49	49
query33	718	209	213	209
query34	1164	456	469	456
query35	883	760	759	759
query36	1338	1137	1240	1137
query37	177	59	60	59
query38	3385	3290	3266	3266
query39	1315	1254	1252	1252
query40	345	87	87	87
query41	37	37	34	34
query42	90	83	88	83
query43	498	481	470	470
query44	1116	683	685	683
query45	191	175	176	175
query46	1073	650	643	643
query47	1674	1494	1505	1494
query48	397	317	304	304
query49	1208	283	282	282
query50	684	314	313	313
query51	5276	5170	5189	5170
query52	87	85	78	78
query53	328	265	258	258
query54	240	173	180	173
query55	83	76	75	75
query56	173	165	179	165
query57	1018	931	941	931
query58	186	153	154	153
query59	2868	2587	2673	2587
query60	204	186	183	183
query61	82	81	85	81
query62	603	375	356	356
query63	293	260	261	260
query64	6135	1786	1751	1751
query65	3318	3257	3240	3240
query66	1411	327	309	309
query67	15681	15012	15123	15012
query68	13364	530	504	504
query69	631	295	294	294
query70	2183	1486	1463	1463
query71	10482	10197	10206	10197
query72	4843	2817	2839	2817
query73	3263	317	312	312
query74	7353	6385	6311	6311
query75	5278	2287	2319	2287
query76	6749	1039	991	991
query77	906	230	242	230
query78	9962	8532	8701	8532
query79	2468	490	505	490
query80	647	316	314	314
query81	447	199	197	197
query82	199	78	80	78
query83	193	121	117	117
query84	275	69	69	69
query85	1096	329	326	326
query86	390	378	415	378
query87	3546	3321	3335	3321
query88	3199	2215	2220	2215
query89	461	355	355	355
query90	2155	188	184	184
query91	165	122	131	122
query92	51	48	44	44
query93	1347	422	437	422
query94	1380	159	157	157
query95	496	452	454	452
query96	631	329	323	323
query97	4280	4150	4146	4146
query98	199	205	181	181
query99	1057	727	724	724
Total cold run time: 313491 ms
Total hot run time: 185962 ms

@doris-robot
Copy link

ClickBench: Total hot run time: 31.06 s
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit e842dd05906946aa34f00ee1eb0ab2ac68e75e33, data reload: false

query1	0.04	0.02	0.02
query2	0.06	0.02	0.02
query3	0.22	0.04	0.05
query4	1.70	0.10	0.07
query5	0.54	0.52	0.52
query6	1.24	0.64	0.62
query7	0.02	0.02	0.01
query8	0.04	0.02	0.03
query9	0.53	0.51	0.49
query10	0.56	0.56	0.57
query11	0.11	0.08	0.08
query12	0.11	0.10	0.08
query13	0.61	0.61	0.60
query14	0.78	0.81	0.81
query15	0.80	0.79	0.76
query16	0.37	0.38	0.40
query17	0.99	0.97	1.01
query18	0.23	0.27	0.24
query19	1.86	1.80	1.84
query20	0.01	0.01	0.01
query21	15.44	0.59	0.56
query22	2.35	2.41	2.08
query23	17.19	0.77	0.80
query24	2.35	1.15	0.92
query25	0.37	0.22	0.12
query26	0.49	0.15	0.14
query27	0.06	0.05	0.06
query28	11.43	0.76	0.77
query29	12.50	3.13	3.14
query30	0.54	0.47	0.49
query31	2.78	0.35	0.35
query32	3.37	0.48	0.49
query33	3.23	3.27	3.21
query34	15.85	4.29	4.31
query35	4.26	4.34	4.30
query36	1.12	1.06	1.06
query37	0.07	0.05	0.05
query38	0.03	0.03	0.03
query39	0.02	0.02	0.02
query40	0.15	0.13	0.13
query41	0.07	0.02	0.02
query42	0.02	0.01	0.02
query43	0.03	0.01	0.02
Total cold run time: 104.54 s
Total hot run time: 31.06 s

@doris-robot
Copy link

Load test result on machine: 'aliyun_ecs.c7a.8xlarge_32C64G'

Load test result on commit e842dd05906946aa34f00ee1eb0ab2ac68e75e33 with default session variables
Stream load json:         19 seconds loaded 2358488459 Bytes, about 118 MB/s
Stream load orc:          58 seconds loaded 1101869774 Bytes, about 18 MB/s
Stream load parquet:      31 seconds loaded 861443392 Bytes, about 26 MB/s
Insert into select:       13.7 seconds inserted 10000000 Rows, about 729K ops/s

* In some p0 test cases we have found dropTable cost more than
  5 seconds, so add more time cost log
@swjtu-zhanglei
Copy link
Contributor Author

run buildall

@doris-robot
Copy link

TPC-H: Total hot run time: 39115 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 865c8d15ffcb1ed9dbf665d5a8d7bbb1bbb13cfa, data reload: false

------ Round 1 ----------------------------------
q1	18181	5403	5360	5360
q2	2452	150	139	139
q3	11253	1206	1175	1175
q4	10595	817	774	774
q5	7881	3206	3202	3202
q6	202	125	124	124
q7	890	509	526	509
q8	9483	1961	1992	1961
q9	7313	6392	6342	6342
q10	8251	3038	3052	3038
q11	415	207	204	204
q12	351	191	191	191
q13	17983	3378	3349	3349
q14	248	221	207	207
q15	552	512	506	506
q16	441	372	385	372
q17	943	538	526	526
q18	7519	6855	6755	6755
q19	1550	1355	1419	1355
q20	606	285	311	285
q21	2778	2431	2449	2431
q22	377	316	310	310
Total cold run time: 110264 ms
Total hot run time: 39115 ms

----- Round 2, with runtime_filter_mode=off -----
q1	5593	5300	5242	5242
q2	337	216	216	216
q3	3379	3258	3281	3258
q4	2046	2080	2071	2071
q5	6056	5879	5940	5879
q6	200	116	118	116
q7	2299	1871	1842	1842
q8	3230	3362	3408	3362
q9	8992	8929	8827	8827
q10	3958	3845	3885	3845
q11	568	463	457	457
q12	830	595	609	595
q13	16901	3170	3116	3116
q14	274	259	268	259
q15	562	509	502	502
q16	521	475	475	475
q17	1871	1851	1814	1814
q18	9588	20018	9548	9548
q19	24253	1554	1555	1554
q20	4674	1953	1931	1931
q21	14405	5397	5292	5292
q22	984	545	562	545
Total cold run time: 111521 ms
Total hot run time: 60746 ms

@doris-robot
Copy link

TPC-DS: Total hot run time: 187084 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 865c8d15ffcb1ed9dbf665d5a8d7bbb1bbb13cfa, data reload: false

query1	926	333	326	326
query2	6558	1962	1918	1918
query3	6705	207	200	200
query4	33639	22198	22174	22174
query5	4448	382	372	372
query6	251	162	169	162
query7	4614	264	259	259
query8	227	180	175	175
query9	8447	2536	2515	2515
query10	421	250	228	228
query11	16600	15461	15488	15461
query12	122	65	67	65
query13	1684	376	390	376
query14	10517	6881	6986	6881
query15	207	190	190	190
query16	5793	253	245	245
query17	958	484	474	474
query18	1799	255	249	249
query19	171	140	133	133
query20	69	73	71	71
query21	190	126	132	126
query22	4923	4799	4809	4799
query23	31654	30988	30870	30870
query24	12615	2817	2818	2817
query25	568	324	310	310
query26	1836	144	148	144
query27	3233	289	295	289
query28	7144	1844	1828	1828
query29	2185	629	633	629
query30	287	137	141	137
query31	958	753	752	752
query32	68	55	47	47
query33	711	216	211	211
query34	1163	468	468	468
query35	899	729	756	729
query36	1295	1233	1225	1225
query37	176	62	61	61
query38	3354	3256	3245	3245
query39	1313	1272	1279	1272
query40	351	90	81	81
query41	37	36	37	36
query42	92	86	86	86
query43	497	467	482	467
query44	1076	695	691	691
query45	191	182	179	179
query46	1077	639	653	639
query47	1631	1504	1539	1504
query48	394	303	302	302
query49	1220	286	276	276
query50	702	308	309	308
query51	5303	5203	5218	5203
query52	85	81	76	76
query53	326	250	255	250
query54	252	192	190	190
query55	78	80	73	73
query56	183	170	170	170
query57	983	917	886	886
query58	198	169	168	168
query59	2976	2773	2712	2712
query60	213	188	197	188
query61	85	84	82	82
query62	626	364	358	358
query63	289	256	265	256
query64	6107	1773	1821	1773
query65	3342	3259	3241	3241
query66	1429	321	312	312
query67	15736	15250	15261	15250
query68	11018	523	506	506
query69	600	296	297	296
query70	1689	1553	1533	1533
query71	10492	10199	10201	10199
query72	4732	2845	2791	2791
query73	2128	316	314	314
query74	6886	6402	6374	6374
query75	5069	2309	2314	2309
query76	6770	1010	1013	1010
query77	887	228	235	228
query78	8988	8722	8602	8602
query79	1015	495	509	495
query80	609	318	319	318
query81	448	206	201	201
query82	212	78	79	78
query83	137	124	125	124
query84	274	77	70	70
query85	1073	324	353	324
query86	400	420	409	409
query87	3496	3389	3344	3344
query88	3079	2202	2203	2202
query89	436	353	366	353
query90	2143	189	189	189
query91	164	128	130	128
query92	56	43	46	43
query93	963	427	443	427
query94	1206	165	160	160
query95	498	453	456	453
query96	615	331	320	320
query97	4234	4189	4183	4183
query98	204	185	183	183
query99	1002	728	738	728
Total cold run time: 305730 ms
Total hot run time: 187084 ms

@doris-robot
Copy link

ClickBench: Total hot run time: 30.81 s
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 865c8d15ffcb1ed9dbf665d5a8d7bbb1bbb13cfa, data reload: false

query1	0.04	0.02	0.02
query2	0.06	0.03	0.03
query3	0.22	0.05	0.05
query4	1.70	0.07	0.07
query5	0.54	0.52	0.52
query6	1.25	0.62	0.62
query7	0.02	0.01	0.01
query8	0.04	0.02	0.02
query9	0.54	0.49	0.48
query10	0.56	0.55	0.57
query11	0.11	0.10	0.08
query12	0.11	0.10	0.09
query13	0.61	0.60	0.60
query14	0.79	0.80	0.82
query15	0.79	0.77	0.78
query16	0.40	0.40	0.40
query17	1.05	0.99	1.03
query18	0.26	0.24	0.26
query19	1.89	1.80	1.81
query20	0.01	0.02	0.01
query21	15.40	0.57	0.58
query22	2.36	2.38	1.28
query23	17.21	0.83	0.78
query24	2.61	1.38	1.35
query25	0.40	0.19	0.18
query26	0.57	0.15	0.15
query27	0.06	0.05	0.06
query28	10.96	0.75	0.75
query29	12.53	3.12	3.23
query30	0.52	0.50	0.49
query31	2.78	0.35	0.34
query32	3.39	0.49	0.48
query33	3.21	3.20	3.21
query34	15.83	4.28	4.29
query35	4.36	4.30	4.34
query36	1.11	1.08	1.08
query37	0.07	0.05	0.04
query38	0.03	0.03	0.03
query39	0.02	0.01	0.01
query40	0.15	0.16	0.13
query41	0.07	0.02	0.02
query42	0.02	0.01	0.02
query43	0.03	0.02	0.02
Total cold run time: 104.68 s
Total hot run time: 30.81 s

@doris-robot
Copy link

Load test result on machine: 'aliyun_ecs.c7a.8xlarge_32C64G'

Load test result on commit 865c8d15ffcb1ed9dbf665d5a8d7bbb1bbb13cfa with default session variables
Stream load json:         19 seconds loaded 2358488459 Bytes, about 118 MB/s
Stream load orc:          58 seconds loaded 1101869774 Bytes, about 18 MB/s
Stream load parquet:      31 seconds loaded 861443392 Bytes, about 26 MB/s
Insert into select:       14.9 seconds inserted 10000000 Rows, about 671K ops/s

@github-actions
Copy link
Contributor

PR approved by anyone and no changes requested.

Copy link

@wm1581066 wm1581066 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@github-actions github-actions bot added the approved Indicates a PR has been approved by one committer. label Jan 25, 2024
@github-actions
Copy link
Contributor

PR approved by at least one committer and no changes requested.

@yiguolei yiguolei merged commit c996958 into apache:master Jan 25, 2024
yiguolei pushed a commit that referenced this pull request Jan 25, 2024
* In some p0 test cases we have found dropTable cost more than
  5 seconds, so add more time cost log
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

approved Indicates a PR has been approved by one committer. dev/3.0.0-merged reviewed

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants